一次 Sysbench opening tables 卡慢的分析过程

一次 Sysbench opening tables 卡慢的分析过程

背景

用 Sysbench 随便跑个压力,然后我用如下命令起压力,只达到了我预期的性能的 10%

1
sysbench --mysql-user=root --mysql-password=123 --mysql-db=sbtest --mysql-host=e237 --mysql-port=3306 --tables=64 --threads=256 --table-size=2000000 --range-size=5 --db-ps-mode=disable --skip-trx=on --mysql-ignore-errors=all --time=1200 --report-interval=1 --histogram=off oltp_point_select run

分析

看了下 MySQL 的进程状态,CPU 消耗很低,再看 processlist 都是 Opening tables,这问题我熟啊,table_open_cache 设置太小,直接干大 10 倍,悲催的是性能依然没有任何变化看了下 MySQL 的进程状态,CPU 消耗很低,再看 processlist 都是 Opening tables,这问题我熟啊,table_open_cache 设置太小,直接干大 10 倍,悲催的是性能依然没有任何变化

image-20241022175210162

image-20241023104502834

难道还有别的地方限制了?我去查了下 status 发现 Table_open_cache_overflows 一直是 0,从状态来看 table_open_cache 肯定够了:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
#mysql -he237 -P3306 -uroot -p123 -e "show global status like '%open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+---------+
| Variable_name | Value |
+----------------------------+---------+
| Com_ha_open | 0 |
| Com_show_open_tables | 0 |
| Innodb_num_open_files | 48 |
| Open_files | 14 |
| Open_streams | 0 |
| Open_table_definitions | 159 |
| Open_tables | 1161 |
| Opened_files | 173 |
| Opened_table_definitions | 138 |
| Opened_tables | 1168 |
| Slave_open_temp_tables | 0 |
| Table_open_cache_hits | 8125315 |
| Table_open_cache_misses | 1168 |
| Table_open_cache_overflows | 0 |
+----------------------------+---------+

#mysql -he237 -P3306 -uroot -p123 -e "show global status like '%Table_open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+---------+
| Variable_name | Value |
+----------------------------+---------+
| Table_open_cache_hits | 9039467 |
| Table_open_cache_misses | 1170 |
| Table_open_cache_overflows | 0 |
+----------------------------+---------+

#mysql -he237 -P3306 -uroot -p123 -e "show global variables like '%Table_open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| table_open_cache | 8192 |
| table_open_cache_instances | 16 |
+----------------------------+-------+

这些有点难绷,因为我用的别人的 sysbench, 于是自己编译了一个重压性能一下就正常了,于是我开始 dump 别人的 sysbench 完整参数,最后发现是我使用的时候配置错误将:–tables=32 设置成了 –tables=64 也就是我的 database 总共只有 32 张表,而我压测的时候写成了 64 张,还有 32 张表不存在导致。

而别人的 sysbench 默认添加了:–mysql-ignore-errors=all 也就是把报错信息都忽略了,导致控制台看不到异常信息

碰到这种问题怎么办?

我们经常碰到业务代码把报错信息吃掉了(类似设置了 –mysql-ignore-errors=all ),同时 SQL 里面拼错了表明或者写错了 Database 名也导致表不存在

所以这里的必杀技(银弹) 抓包(或者堆栈热点分析):

image-20241023101835801

上图中只要不是 1146 的都是表明正确的请求,可以看到 RT 是 0.1-0.2 毫秒之间;但是 response Error 1146 报错的 RT 就很大了,同时抓包里 1146 也给出了错误原因

1
2
3
4
5
+-------+------+---------------------------------------+
| Level | Code | Message |
+-------+------+---------------------------------------+
| Error | 1146 | Table 'sbtest.sbtest42' doesn't exist |
+-------+------+---------------------------------------+

正常时 50 万 QPS 的 RT:

1
2
3
	 time								port	avg_rt	svc_rt  up_rt    QPS  	drop	rtt
2024-10-23 10:14:57 P3306 227 228 0 532688 0 34
2024-10-23 10:14:58 P3306 227 228 0 533439 0 34

异常时 5 万 QPS 的 RT:

1
2
3
4
5
6
7
	 time								port	avg_rt	svc_rt  up_rt    QPS  	drop	rtt
2024-10-23 10:13:56 P3306 2201 2201 0 58910 0 34
2024-10-23 10:13:57 P3306 2195 2195 0 59141 0 34
2024-10-23 10:13:58 P3306 2203 2203 0 58923 0 34
2024-10-23 10:13:59 P3306 2190 2191 0 59266 0 34
2024-10-23 10:14:00 P3306 2198 2198 0 59018 0 34
2024-10-23 10:14:01 P3306 2242 2242 0 57926 0 34

从 RT 确实可以看出来是 3306 端口返回/响应慢了,我在 MySQLD 的日志里也搜索了,应该是没有记录这种 1146 错误

如果多看几次 processlist 的话还会发现 Opening table 的 SQL 对应的表明都是大于 31 的,表名小的 SQL 就不会出现 Opening table

总结

这个问题我第一时间没有想到抓包,显示根据经验 Opening tables 就是打开表慢了,然后调大 cache 参数,还不好用就觉得超出我的理解有点慌!

然后想到去比较参数/版本的差异,运气好发现了参数的差异;如果运气不好我重新编译然后复制白屏的命令参数估计还是发现不了。

所以我在想有什么更好的办法能识别这种问题,最后的结论居然还是抓个包看看,并且真管用,正好和这篇方法论呼应一下:https://articles.zsxq.com/id_mnp5z56gl0wi.html

延伸

很多时候开发很坑人,把业务异常堆栈吃了不输出,就拿这个例子来说也有业务写错表名,然后报错又不输出就会出现和问题一样的问题,导致分析问题的时候发现很奇怪好好的系统就是慢,这个时候除了抓包还可以通过 perf/jstack 去看看堆栈,抓下热点

推上也有一些讨论,可以参考下别人的思路:https://x.com/plantegg/status/1851066206163521712

如果你觉得看完对你很有帮助可以通过如下方式找到我

find me on twitter: @plantegg

知识星球:https://t.zsxq.com/0cSFEUh2J

开了一个星球,在里面讲解一些案例、知识、学习方法,肯定没法让大家称为顶尖程序员(我自己都不是),只是希望用我的方法、知识、经验、案例作为你的垫脚石,帮助你快速、早日成为一个基本合格的程序员。

争取在星球内:

  • 养成基本动手能力
  • 拥有起码的分析推理能力–按我接触的程序员,大多都是没有逻辑的
  • 知识上教会你几个关键的知识点
image-20240324161113874